freeswitch@cyzlaptop> version

FreeSWITCH Version 1.9.0+git~20170518T231917Z~a1fc18aee5~32bit (git a1fc18a 2017-05-18 23:19:17Z 32bit)

freeswitch@cyzlaptop>

+OK console log level set to DEBUG

originate user/1001 5000
2017-06-15 10:18:38.336196 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables
2017-06-15 10:18:38.336196 [DEBUG] switch_ivr_originate.c:2147 Parsing global variables
2017-06-15 10:18:38.346202 [NOTICE] switch_channel.c:1104 New Channel sofia/internal/1001@192.168.1.154:39239 [e54ec0ce-c93e-4833-bff1-c8a512541fe1]
2017-06-15 10:18:38.346202 [DEBUG] mod_sofia.c:5026 (sofia/internal/1001@192.168.1.154:39239) State Change CS_NEW -> CS_INIT
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.154:39239) Running State Change CS_INIT (Cur 1 Tot 1)
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.1.154:39239) State INIT
2017-06-15 10:18:38.346202 [DEBUG] mod_sofia.c:93 sofia/internal/1001@192.168.1.154:39239 SOFIA INIT
2017-06-15 10:18:38.346202 [DEBUG] sofia_glue.c:1298 sofia/internal/1001@192.168.1.154:39239 sending invite version: 1.9.0 git a1fc18a 2017-05-18 23:19:17Z 32bit
Local SDP:
v=0
o=FreeSWITCH 1497475432 1497475433 IN IP4 192.168.1.161
s=FreeSWITCH
c=IN IP4 192.168.1.161
t=0 0
m=audio 17686 RTP/AVP 102 9 0 8 104 101
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:104 telephone-event/48000
a=fmtp:104 0-16
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
m=video 17848 RTP/AVP 103
b=AS:1024
a=rtpmap:103 VP8/90000
a=sendrecv
a=rtcp-fb:103 ccm fir
a=rtcp-fb:103 ccm tmmbr
a=rtcp-fb:103 nack
a=rtcp-fb:103 nack pli

2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:40 sofia/internal/1001@192.168.1.154:39239 Standard INIT
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:48 (sofia/internal/1001@192.168.1.154:39239) State Change CS_INIT -> CS_ROUTING
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:627 (sofia/internal/1001@192.168.1.154:39239) State INIT going to sleep
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.154:39239) Running State Change CS_ROUTING (Cur 1 Tot 1)
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.154:39239) State ROUTING
2017-06-15 10:18:38.346202 [DEBUG] mod_sofia.c:154 sofia/internal/1001@192.168.1.154:39239 SOFIA ROUTING
2017-06-15 10:18:38.346202 [DEBUG] switch_ivr_originate.c:67 (sofia/internal/1001@192.168.1.154:39239) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.154:39239) State ROUTING going to sleep
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.154:39239) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 1)
2017-06-15 10:18:38.346202 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.1.154:39239 entering state [calling][0]
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@192.168.1.154:39239) State CONSUME_MEDIA
2017-06-15 10:18:38.346202 [DEBUG] switch_core_state_machine.c:662 (sofia/internal/1001@192.168.1.154:39239) State CONSUME_MEDIA going to sleep
2017-06-15 10:18:38.585210 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.1.154:39239 entering state [proceeding][180]
2017-06-15 10:18:38.585210 [NOTICE] sofia.c:7355 Ring-Ready sofia/internal/1001@192.168.1.154:39239!
2017-06-15 10:18:38.585210 [DEBUG] switch_channel.c:3353 (sofia/internal/1001@192.168.1.154:39239) Callstate Change DOWN -> RINGING
2017-06-15 10:18:40.496057 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.1.154:39239 entering state [completing][200]
2017-06-15 10:18:40.496057 [DEBUG] sofia.c:7257 Remote SDP:
v=0
o=Zoiper 0 3 IN IP4 192.168.1.154
s=Zoiper
c=IN IP4 192.168.1.154
t=0 0
m=audio 59668 RTP/AVP 0 3 8 101
a=rtpmap:0 PCMU/8000
a=rtpmap:3 GSM/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
m=video 0 RTP/AVP 116 115

2017-06-15 10:18:40.496057 [DEBUG] sofia.c:7247 Channel sofia/internal/1001@192.168.1.154:39239 entering state [ready][200]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [GSM:3:8000:20:13200:1]/[opus:116:48000:20:0:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [GSM:3:8000:20:13200:1]/[G722:9:8000:20:64000:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMU:0:8000:20:64000:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [GSM:3:8000:20:13200:1]/[PCMA:8:8000:20:64000:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5110 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5165 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5026 Set telephone-event payload to 101@8000
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:3425 Set Codec sofia/internal/1001@192.168.1.154:39239 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2017-06-15 10:18:40.496057 [DEBUG] switch_core_codec.c:111 sofia/internal/1001@192.168.1.154:39239 Original read codec set to PCMU:0
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5369 Set telephone-event payload to 101@8000
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:5427 sofia/internal/1001@192.168.1.154:39239 Set 2833 dtmf send payload to 101 recv payload to 101
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:8144 AUDIO RTP [sofia/internal/1001@192.168.1.154:39239] 192.168.1.161 port 17686 -> 192.168.1.154 port 59668 codec: 0 ms: 20
2017-06-15 10:18:40.496057 [DEBUG] switch_rtp.c:4107 Starting timer [soft] 160 bytes per 20ms
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:8447 sofia/internal/1001@192.168.1.154:39239 Set 2833 dtmf send payload to 101
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:8454 sofia/internal/1001@192.168.1.154:39239 Set 2833 dtmf receive payload to 101
2017-06-15 10:18:40.496057 [DEBUG] switch_core_media.c:8477 sofia/internal/1001@192.168.1.154:39239 Set rtp dtmf delay to 40
2017-06-15 10:18:40.496057 [NOTICE] sofia.c:8383 Channel [sofia/internal/1001@192.168.1.154:39239] has been answered
2017-06-15 10:18:40.496057 [DEBUG] switch_channel.c:3780 (sofia/internal/1001@192.168.1.154:39239) Callstate Change RINGING -> ACTIVE
2017-06-15 10:18:40.504889 [DEBUG] switch_ivr_originate.c:3709 Originate Resulted in Success: [sofia/internal/1001@192.168.1.154:39239]
2017-06-15 10:18:40.516130 [DEBUG] switch_ivr_originate.c:3709 Originate Resulted in Success: [sofia/internal/1001@192.168.1.154:39239]

+OK e54ec0ce-c93e-4833-bff1-c8a512541fe1

2017-06-15 10:18:40.516130 [DEBUG] switch_ivr.c:2194 (sofia/internal/1001@192.168.1.154:39239) State Change CS_CONSUME_MEDIA -> CS_ROUTING
2017-06-15 10:18:40.516130 [NOTICE] switch_ivr.c:2201 Transfer sofia/internal/1001@192.168.1.154:39239 to XML[5000@default]
2017-06-15 10:18:40.516130 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.154:39239) Running State Change CS_ROUTING (Cur 1 Tot 1)
2017-06-15 10:18:40.516130 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.154:39239) State ROUTING
2017-06-15 10:18:40.516130 [DEBUG] mod_sofia.c:154 sofia/internal/1001@192.168.1.154:39239 SOFIA ROUTING
2017-06-15 10:18:40.516130 [DEBUG] switch_core_state_machine.c:236 sofia/internal/1001@192.168.1.154:39239 Standard ROUTING
2017-06-15 10:18:40.516130 [INFO] mod_dialplan_xml.c:637 Processing  <0000000000>->5000 in context default
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->unloop] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (PASS) [unloop] ${unroll_loops}(true) =~ /^true$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [unloop] ${sip_looped_call}() =~ /^true$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->tod_example] continue=true
Dialplan: sofia/internal/1001@192.168.1.154:39239 Date/Time Match (PASS) [tod_example] break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Action set(open=true)
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->holiday_example] continue=true
Dialplan: sofia/internal/1001@192.168.1.154:39239 Date/TimeMatch (FAIL) [holiday_example] break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->global-intercept] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [global-intercept] destination_number(5000) =~ /^886$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->group-intercept] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [group-intercept] destination_number(5000) =~ /^\*8$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->intercept-ext] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [intercept-ext] destination_number(5000) =~ /^\*\*(\d+)$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->redial] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [redial] destination_number(5000) =~ /^(redial|870)$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->global] continue=true
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [global] ${call_debug}(false) =~ /^true$/ break=never
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [global] ${default_password}(4321) =~ /^1234$/ break=never
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [global] ${rtp_has_crypto}() =~ /^(AEAD_AES_256_GCM_8|AEAD_AES_128_GCM_8|AES_CM_256_HMAC_SHA1_80|AES_CM_192_HMAC_SHA1_80|AES_CM_128_HMAC_SHA1_80|AES_CM_256_HMAC_SHA1_32|AES_CM_192_HMAC_SHA1_32|AES_CM_128_HMAC_SHA1_32|AES_CM_128_NULL_AUTH)$/ break=never
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [global] ${endpoint_disposition}(ANSWER) =~ /^(DELAYED NEGOTIATION)/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->snom-demo-2] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [snom-demo-2] destination_number(5000) =~ /^9001$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->snom-demo-1] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [snom-demo-1] destination_number(5000) =~ /^9000$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [eavesdrop] destination_number(5000) =~ /^88(\d{4})$|^\*0(.*)$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [eavesdrop] destination_number(5000) =~ /^779$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->call_return] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [call_return] destination_number(5000) =~ /^\*69$|^869$|^lcr$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->del-group] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [del-group] destination_number(5000) =~ /^80(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->add-group] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [add-group] destination_number(5000) =~ /^81(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->call-group-simo] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [call-group-simo] destination_number(5000) =~ /^82(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->call-group-order] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [call-group-order] destination_number(5000) =~ /^83(\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->extension-intercom] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [extension-intercom] destination_number(5000) =~ /^8(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->Local_Extension] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [Local_Extension] destination_number(5000) =~ /^(10[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->Local_Extension_Skinny] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [Local_Extension_Skinny] destination_number(5000) =~ /^(11[01][0-9])$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->group_dial_sales] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [group_dial_sales] destination_number(5000) =~ /^2000$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->group_dial_support] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [group_dial_support] destination_number(5000) =~ /^2001$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->group_dial_billing] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [group_dial_billing] destination_number(5000) =~ /^2002$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->operator] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [operator] destination_number(5000) =~ /^(operator|0)$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->vmain] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [vmain] destination_number(5000) =~ /^vmain$|^4000$|^\*98$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->sip_uri] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [sip_uri] destination_number(5000) =~ /^sip:(.*)$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->nb_conferences] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [nb_conferences] destination_number(5000) =~ /^(30\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->wb_conferences] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [wb_conferences] destination_number(5000) =~ /^(31\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->uwb_conferences] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [uwb_conferences] destination_number(5000) =~ /^(32\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->cdquality_conferences] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [cdquality_conferences] destination_number(5000) =~ /^(33\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->cdquality_stereo_conferences] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [cdquality_stereo_conferences] destination_number(5000) =~ /^(35\d{2}).*?-screen$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->conference-canvases] continue=true
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [conference-canvases] destination_number(5000) =~ /(35\d{2})-canvas-(\d+)/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->conf mod] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [conf mod] destination_number(5000) =~ /^6070-moderator$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->cdquality_conferences] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [cdquality_conferences] destination_number(5000) =~ /^(35\d{2})$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->freeswitch_public_conf_via_sip] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [freeswitch_public_conf_via_sip] destination_number(5000) =~ /^9(888|8888|1616|3232)$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [mad_boss_intercom] destination_number(5000) =~ /^0911$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->mad_boss_intercom] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [mad_boss_intercom] destination_number(5000) =~ /^0912$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->mad_boss] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [mad_boss] destination_number(5000) =~ /^0913$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->ivr] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (FAIL) [ivr] destination_number(5000) =~ /^1234$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 parsing [default->ivr_demo] continue=false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Regex (PASS) [ivr_demo] destination_number(5000) =~ /^5000$/ break=on-false
Dialplan: sofia/internal/1001@192.168.1.154:39239 Action answer()
Dialplan: sofia/internal/1001@192.168.1.154:39239 Action sleep(2000)
Dialplan: sofia/internal/1001@192.168.1.154:39239 Action ivr(demo_ivr)
2017-06-15 10:18:40.516130 [INFO] switch_channel.c:3130 sofia/internal/1001@192.168.1.154:39239 Flipping CID from "" <0000000000> to "Outbound Call" <1001>
2017-06-15 10:18:40.516130 [DEBUG] switch_core_state_machine.c:286 (sofia/internal/1001@192.168.1.154:39239) State Change CS_ROUTING -> CS_EXECUTE
2017-06-15 10:18:40.516130 [DEBUG] switch_core_state_machine.c:643 (sofia/internal/1001@192.168.1.154:39239) State ROUTING going to sleep
2017-06-15 10:18:40.516130 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.154:39239) Running State Change CS_EXECUTE (Cur 1 Tot 1)
2017-06-15 10:18:40.516130 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.1.154:39239) State EXECUTE
2017-06-15 10:18:40.516130 [DEBUG] mod_sofia.c:209 sofia/internal/1001@192.168.1.154:39239 SOFIA EXECUTE
2017-06-15 10:18:40.516130 [DEBUG] switch_core_state_machine.c:328 sofia/internal/1001@192.168.1.154:39239 Standard EXECUTE
EXECUTE sofia/internal/1001@192.168.1.154:39239 set(open=true)
2017-06-15 10:18:40.516130 [DEBUG] mod_dptools.c:1570 SET sofia/internal/1001@192.168.1.154:39239 [open]=[true]
EXECUTE sofia/internal/1001@192.168.1.154:39239 answer()
EXECUTE sofia/internal/1001@192.168.1.154:39239 sleep(2000)

freeswitch@cyzlaptop> 2017-06-15 10:18:40.635227 [DEBUG] switch_rtp.c:7266 Correct audio ip/port confirmed.
EXECUTE sofia/internal/1001@192.168.1.154:39239 ivr(demo_ivr)
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-exit'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-sub'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-exec-app'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-play-sound'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-back'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:743 switch_ivr_menu_stack_xml_add binding 'menu-top'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:880 building menu 'demo_ivr'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '1'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '2'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '3'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '4'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '5'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:880 building menu 'demo_ivr_submenu'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-top' to '*'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-sub' to '6'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-exec-app' to '/^(10[01][0-9])$/'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:964 binding menu action 'menu-top' to '9'
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_menu.c:483 Executing IVR menu demo_ivr
2017-06-15 10:18:42.534925 [DEBUG] switch_ivr_play_say.c:70 No language specified - Using [en]
2017-06-15 10:18:42.564576 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-welcome_to_freeswitch.wav] (en:en)
2017-06-15 10:18:42.564576 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2017-06-15 10:18:45.155184 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-welcome_to_freeswitch.wav
2017-06-15 10:18:45.274518 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-this_ivr_will_let_you_test_features.wav] (en:en)
2017-06-15 10:18:45.274518 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2017-06-15 10:18:49.255031 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-this_ivr_will_let_you_test_features.wav
2017-06-15 10:18:49.355210 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-you_may_exit_by_hanging_up.wav] (en:en)
2017-06-15 10:18:49.355210 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2017-06-15 10:18:51.954949 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-you_may_exit_by_hanging_up.wav
2017-06-15 10:18:52.074617 [DEBUG] switch_ivr_play_say.c:250 Handle play-file:[ivr/ivr-enter_ext_pound.wav] (en:en)
2017-06-15 10:18:52.074617 [DEBUG] switch_ivr_play_say.c:1498 Codec Activated L16@8000hz 1 channels 20ms
2017-06-15 10:18:52.575134 [NOTICE] sofia.c:1079 Hangup sofia/internal/1001@192.168.1.154:39239 [CS_EXECUTE] [NORMAL_CLEARING]
2017-06-15 10:18:52.575134 [DEBUG] switch_ivr_play_say.c:1942 done playing file F:/temp/fs-src-win/Win32/Debug/sounds/en/us/callie/ivr/ivr-enter_ext_pound.wav
2017-06-15 10:18:52.575134 [DEBUG] switch_ivr_menu.c:377 waiting for 4/4 digits t/o 2000
2017-06-15 10:18:52.575134 [DEBUG] switch_ivr_menu.c:424 digits ''
2017-06-15 10:18:52.575134 [DEBUG] switch_ivr_menu.c:661 IVR menu 'demo_ivr' no input detected
2017-06-15 10:18:52.575134 [DEBUG] switch_ivr_menu.c:673 exit-sound 'voicemail/vm-goodbye.wav'
2017-06-15 10:18:52.575134 [DEBUG] switch_core_session.c:2884 sofia/internal/1001@192.168.1.154:39239 skip receive message [PHONE_EVENT] (channel is hungup already)
2017-06-15 10:18:52.575134 [DEBUG] switch_core_state_machine.c:650 (sofia/internal/1001@192.168.1.154:39239) State EXECUTE going to sleep
2017-06-15 10:18:52.575134 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.154:39239) Running State Change CS_HANGUP (Cur 1 Tot 1)
2017-06-15 10:18:52.575134 [DEBUG] switch_core_state_machine.c:850 (sofia/internal/1001@192.168.1.154:39239) Callstate Change ACTIVE -> HANGUP
2017-06-15 10:18:52.575134 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@192.168.1.154:39239) State HANGUP
2017-06-15 10:18:52.575134 [DEBUG] mod_sofia.c:449 Channel sofia/internal/1001@192.168.1.154:39239 hanging up, cause: NORMAL_CLEARING
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:60 sofia/internal/1001@192.168.1.154:39239 Standard HANGUP, cause: NORMAL_CLEARING
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:852 (sofia/internal/1001@192.168.1.154:39239) State HANGUP going to sleep
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:619 (sofia/internal/1001@192.168.1.154:39239) State Change CS_HANGUP -> CS_REPORTING
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:584 (sofia/internal/1001@192.168.1.154:39239) Running State Change CS_REPORTING (Cur 1 Tot 1)
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@192.168.1.154:39239) State REPORTING
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:174 sofia/internal/1001@192.168.1.154:39239 Standard REPORTING, cause: NORMAL_CLEARING
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:938 (sofia/internal/1001@192.168.1.154:39239) State REPORTING going to sleep
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:610 (sofia/internal/1001@192.168.1.154:39239) State Change CS_REPORTING -> CS_DESTROY
2017-06-15 10:18:52.584445 [DEBUG] switch_core_session.c:1712 Session 1 (sofia/internal/1001@192.168.1.154:39239) Locked, Waiting on external entities
2017-06-15 10:18:52.584445 [NOTICE] switch_core_session.c:1730 Session 1 (sofia/internal/1001@192.168.1.154:39239) Ended
2017-06-15 10:18:52.584445 [NOTICE] switch_core_session.c:1734 Close Channel sofia/internal/1001@192.168.1.154:39239 [CS_DESTROY]
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:741 (sofia/internal/1001@192.168.1.154:39239) Running State Change CS_DESTROY (Cur 0 Tot 1)
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@192.168.1.154:39239) State DESTROY
2017-06-15 10:18:52.584445 [DEBUG] mod_sofia.c:354 sofia/internal/1001@192.168.1.154:39239 SOFIA DESTROY
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:181 sofia/internal/1001@192.168.1.154:39239 Standard DESTROY
2017-06-15 10:18:52.584445 [DEBUG] switch_core_state_machine.c:751 (sofia/internal/1001@192.168.1.154:39239) State DESTROY going to sleep

